\documentclass{article}
\usepackage{Listings}
\title{Log4net Tutorial}
\author{jfang}
\begin{document}
\maketitle
\section{Getting Started}
I've found logging to be one of the most effective debugging and troubleshooting techniques in my engineering bag, but I'm surprised at how infrequently other people seem to use it.  The arguments orbit around the notion that adding any form of logging won't be that helpful, or that it will slow the application to a crawl.  My experience with application logging has been very positive, and quite frankly I would be a lot less effective without it.\\
This post is the first in a series aimed at making you comfortable and confident in using log4net as an application logging layer in your .NET applications.  Seriously, it'll make your life a lot easier.
\subsection{About log4net}
 My logging layer of choice for .NET is log4net from the Apache Software Foundation.  It's open source, well-documented, extensible, and comes ripe with features right off the vine.  There are alternative logging platforms available if open source isn't an option for you, such as the Microsoft Logging Application Block or, if you're willing to fork out some cash, LucidLog.Net; I can't comment on them directly as I have no experience with either - I've heard good things, but I've also heard that log4net is more feature-rich that both of these.\\\\
Note: This series of posts references log4net version 1.2.10.
\subsection{Getting log4net}
log4net is available here as a zip archive.\\
The archive contains a ton of stuff; for posterity, here are some hilites of what you'll find in there:\\
\begin{itemize}
\item $\backslash$bin houses the log4net binaries. The distribution contains versions of log4net built for specific platforms of .NET, including Microsoft .NET, Mono, Rotor, and the Compact Framework.
\item $\backslash$doc contains the log4net documentation.  Open index.html to start your perusing.
\item $\backslash$examples contains several small, digestible sample logging applications in various languages and platforms.
\item $\backslash$src holds the log4net source code.
\item $\backslash$tests contains unit tests for the log4net source code.
\end{itemize}
\subsection{A Quick Example}
\begin{enumerate}
\item Open Visual Studio and create a new Console application project.
\item Add to the project a reference to the $\backslash$bin$\backslash$net$\backslash$2.0$\backslash$release$\backslash$log4net.dll assembly in the log4net distribution.
\item Modify your Main() method like so:
\end{enumerate}
\begin{verbatim}
   1 using System;  
   2 namespace Tutorial1_GettingStarted  
   3 {  
   4     class Program  
   5     {  
   6         static void Main( string[] args )  
   7         {  
   8             log4net.Config.BasicConfigurator.Configure();  
   9             log4net.ILog log = log4net.LogManager.GetLogger
                                                  ( typeof( Program ) );
  10   
  11             log.Debug( "Hello World!" );  
  12             log.Info( "I'm a simple log4net tutorial." );  
  13             log.Warn( "... better be careful ..." );  
  14             log.Error( "ruh-roh: an error occurred" );  
  15             log.Fatal( "OMG we're dooooooomed!" );  
  16              
  17             Console.ReadLine();  // so you can read the output  
  18         }  
  19     }  
  20 }  
\end{verbatim}
Before running the application, take a close look at the code.  On line 8, the log4net subsystem is configured in the most basic way possible.  Using the BasicConfigurator will cause log4net to output log entries to the console using a default layout (more on layouts in a moment).  log4net configuration is a very broad topic and can get rather deep, but it can be this shallow and narrow too. \\
Line 9 requests a logger from the LogManager object.  Logger objects implement the ILog interface, which is what your application will use to instrument itself and percolate log entries.\\
Lines 11-15 use the logger to log a few statements with various severity levels.  log4net defines 5 such levels:
\begin{itemize}
\item Debug: fine-grained statements concerning program state, typically used for debugging;
\item Info: informational statements concerning program state, representing program events or behavior tracking;
\item Warn: statements that describe potentially harmful events or states in the program;
\item  Error: statements that describe non-fatal errors in the application; this level is used quite often for logging handled exceptions;
\item Fatal: statements representing the most severe of error conditions, assumedly resulting in program termination.
\end{itemize}
Compile and run the application, and you'll see output to the console similar to the following:\\
view plaincopy to clipboardprint?
\begin{verbatim}
1 93 [10] DEBUG Tutorial1_GettingStarted.Program (null) 
                                   - Hello World!
2 156 [10] INFO Tutorial1_GettingStarted.Program (null)
                                   - I'm a simple log4net tutorial.
3 156 [10] WARN Tutorial1_GettingStarted.Program (null)
                                   - ... better be careful ...  
4 156 [10] ERROR Tutorial1_GettingStarted.Program (null)
                                   - ruh-roh: an error occurred
5 156 [10] FATAL Tutorial1_GettingStarted.Program (null)
                                   - OMG we're dooooooomed!  
\end{verbatim}
Note that each log statement is accompanied by a bunch of data.  I mentioned that the BasicConfigurator uses a default layout; layouts determine how log4net formats a log statement.  In this case, the BasicConfigurator is using a layout that includes stuff like the identifier of the thread from which the log entry was made, the level of the log entry, etc.
\section{Basic xml configuration}
In this post, I'll show you how to use an XML file to configure log4net, and demonstrate some of the basic ways you can control the verbosity of your log.
sebsection{Using the XML Configurator}
Open Visual Studio, create a new console application, and add a reference to the log4net assembly.  Add the following code to your Main() method:
\begin{verbatim}
   1 using System;  
   2   
   3 namespace Tutorial2_BasicXmlConfiguration  
   4 {  
   5     class Program  
   6     {  
   7         static void Main( string[] args )  
   8         {  
   9             log4net.Config.XmlConfigurator.Configure();  
  10             log4net.ILog log = log4net.LogManager.GetLogger
                                               ( typeof( Program ) );
  11   
  12             log.Info( "beginning loop" );  
  13   
  14             for( int c = 0; c < 100; ++c )  
  15             {  
  16                 log.DebugFormat( "iteration #{0}", c );  
  17             }  
  18   
  19             log.Info( "loop has completed" );  
  20   
  21             Console.ReadLine();              
  22         }  
  23     }  
  24 }  
\end{verbatim}
On line 9, log4net is bootstrapped using the XmlConfigurator.  This configuration strategy relies on an XML document to supply configuration for log4net.  The static Configure method is overloaded to accept the configuration XML from a file, stream, URI, or an XmlElement object; the parameterless form of the method used here instructs log4net to load the XML from the application's configuration file.\\
In addition to the Configure method, the XmlConfigurator offers a static ConfigureAndWatch() method that accepts a FileInfo reference.  ConfigureAndWatch() will monitor the configuration XML file and reconfigure log4net when a change is detected.  This allows you to alter logging behavior at whim while the application is running - very handy for troubleshooting applications in the field, but it adds overhead in the form of a FileSystemWatcher used to monitor the configuration file.\\
Add the following application configuration file to the console project:
\begin{verbatim}
   1 <configuration>  
   2   <configSections>  
   3     <section name="log4net" 
           type="log4net.Config.Log4NetConfigurationSectionHandler,
                                                          log4net"/>
   4   </configSections>  
   5   
   6   <log4net>  
   7     <appender name="ConsoleAppender" 
                           type="log4net.Appender.ConsoleAppender">
   8       <layout type="log4net.Layout.SimpleLayout" />
   9     </appender>  
  10   
  11     <root>  
  12       <level value="ALL" />  
  13       <appender-ref ref="ConsoleAppender" />  
  14     </root>  
  15   </log4net>  
  16 </configuration>  
\end{verbatim}
There are a few important things in there.  First is the declaration of the log4net configuration section on line 3; this is mandatory.  The log4net configuration takes up lines 6-15.  There are two parts to the configuration:
\begin{enumerate}
\item one or more appender declarations taking the form of $<$appender /$>$ elements, and
\item the root logger declaration, represented by the $<$root /$>$ XML element.
\end{enumerate}
A real discussion of appenders will have to wait; for now, suffice it to say that a log4net appender is a place where your log entries end up.  In this case, the log is being ``appended'' to the console.\\
The root logger controls the general behavior of log4net.  In this example, the root logger is told to send everything to the console appender.\\
Time to compile and run.  You'll get the following output:
\begin{verbatim}
   1 INFO - beginning loop  
   2 DEBUG - iteration #0  
   3 DEBUG - iteration #1  
   4 DEBUG - iteration #2  
   5 DEBUG - iteration #3  
   6 DEBUG - iteration #4  
   ...  
  98 DEBUG - iteration #96  
  99 DEBUG - iteration #97  
 100 DEBUG - iteration #98  
 101 DEBUG - iteration #99  
 102 INFO - loop has completed  
\end{verbatim}
\subsection{Taming log4net Output}
This example logs a fair amount of cruft.  The DEBUG-level logging inside of the loop overshadows the INFO-level logging outside of the loop.  In a real scenario, this DEBUG-level output may be necessary when troubleshooting application behavior, but it becomes a lot noise when instrumenting the application in production.\\
Thankfully log4net provides a filter on the logging output.  In your project's app.config, find the $<$level /$>$ XML element and alter it like so:
\begin{verbatim}
   1 <level value="INFO" />  
\end{verbatim}
Compile and run; the program log is significantly truncated:
\begin{enumerate}
\item INFO - beginning loop
\item INFO - loop has completed
\end{enumerate}
Specifically, all DEBUG-level log entries are missing from the log output.  The level value instructs the logger of the minimum level at which log entries should be processed.  It can be one of these values:
\begin{itemize}
\item ALL: all log entries are appended to the log;
\item DEBUG: Debug, Info, Warn, Error, and Fatal messages are appended to the log.  This is functionally identical to ALL;
\item INFO: Info, Warn, Error, and Fatal messages are appended to the log;
\item WARN: Warn, Error, and Fatal messages are appended to the log;
\item ERROR: Error and Fatal messages are appended to the log;
\item FATAL: only Fatal messages are appended to the log;
\item OFF: all log entries are ignored.  Logging is effectively disabled in this case.
\end{itemize}
\section{appenders}
I've discussed  using XML to configure lognet, during which I briefly touched on log4net appenders.  An appender is an object that persists your log messages someplace.  In this post, I'd like to give you a quick overview of the wealth of apppenders available in log4net and show you how you can use them to direct a single log message to multiple places.
\subsection{A Quick Survey}
Here is a quick sampling of the appenders available in the log4net distribution:
\begin{tabular}{l|p{6cm}}
Type Name&Description\\
\hline
log4net.Appender.AdoNetAppender&Appender that logs to a database.\\\hline
log4net.Appender.AnsiColorTerminalAppender&Appends logging events to the terminal using ANSI color escape sequences.\\\hline
log4net.Appender.AspNetTraceAppender&Appends log events to the ASP.NET TraceContext system.\\\hline
log4net.Appender.BufferingForwardingAppender&Buffers events and then forwards them to attached appenders.\\\hline
log4net.Appender.ColoredConsoleAppender&Appends logging events to the console.\\\hline
log4net.Appender.ConsoleAppender&Appends logging events to the console.\\\hline
log4net.Appender.DebugAppender&Appends log events to the Debug system.\\\hline
log4net.Appender.EventLogAppender&Writes events to the system event log.\\\hline
log4net.Appender.ForwardingAppender&This appender forwards logging events to attached appenders.\\\hline
log4net.Appender.FileAppender&Appends logging events to a file.\\\hline
log4net.Appender.LocalSyslogAppender&Logs events to a local syslog service.\\\hline
log4net.Appender.MemoryAppender&Stores logging events in an array.\\\hline
log4net.Appender.NetSendAppender&Logs entries by sending network messages using the NetMessageBufferSend native function.\\\hline
log4net.Appender.OutputDebugStringAppender&Appends log events to the OutputDebugString system.\\\hline
log4net.Appender.RemoteSyslogAppender&Logs events to a remote syslog daemon.\\\hline
log4net.Appender.RemotingAppender&Delivers logging events to a remote loggingsink.\\\hline
log4net.Appender.RollingFileAppender&Appender that rolls log files based on size or date or both.\\\hline
log4net.Appender.SmtpAppender&Send an e-mail when a specific logging event occurs, typically on errors or fatal errors.\\\hline
log4net.Appender.SmtpPickupDirAppender&Send an email when a specific logging event occurs, typically on errors or fatal errors. Rather than sending via smtp it writes a file that  another service, such as the IIS SMTP agent, can use to manage sending the messages.\\\hline
log4net.Appender.TelnetAppender&Appender that allows clients to connect via Telnet to receive log messages.\\\hline
log4net.Appender.TraceAppender&Appends log events to the Trace system.\\\hline
log4net.Appender.UdpAppender&Sends logging events as connectionless UDP datagrams to a remote host or multicast using the UdpClient class.\\\hline
\end{tabular}\\
There's a lot of them, so to keep this post reasonable I'm focusing on the most basic appenders: the console appenders, debug appenders, and file appenders.  However, all of the available appenders are covered in detail in the log4net documentation if you want to learn more about them, and I'll be describing other appenders in upcoming posts as well.
ConsoleAppender and ColoredConsoleAppender\\
These appenders are useful only for console applications, where they provide immediate feedback during program execution.\\
There is one configurable aspect of the ConsoleAppender - the target property identifies what output stream to use when outputting log entries:
\begin{verbatim}
   1 <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">  
   2     <target value="Console.Error" />  
   3     <layout type="log4net.Layout.SimpleLayout" />  
   4 </appender>  
\end{verbatim}
It can be either ``Console.Out'' (the default value if left uspecified) to use the standard output stream or ``Console.Error'' to use the standard error stream.\\
I always favor ColoredConsoleAppender over ConsoleAppender, because the ColoredConsoleAppender will colorize the log message by its severity level.  This makes finding relevant log messages amidst the program output a lot easier.  For example, compare this output from the ConsoleAppender:\\
to the same output from the ColoredConsoleAppender:\\
The color mapping is completely configurable, as shown in this example appender configuration XML:
\begin{verbatim}
   1 <appender name="ColoredConsoleAppender" 
				type="log4net.Appender.ColoredConsoleAppender">  
   2   <target value="Console.Error" />  
   3   <mapping>  
   4     <level value="FATAL" />  
   5     <foreColor value="Red" />  
   6     <backColor value="White" />  
   7   </mapping>  
   8   <mapping>  
   9     <level value="ERROR" />  
  10     <foreColor value="Red, HighIntensity" />  
  11   </mapping>  
  12   <mapping>  
  13     <level value="WARN" />  
  14     <foreColor value="Yellow" />  
  15   </mapping>  
  16   <mapping>  
  17     <level value="INFO" />  
  18     <foreColor value="Cyan" />  
  19   </mapping>  
  20   <mapping>  
  21     <level value="DEBUG" />  
  22     <foreColor value="Green" />  
  23   </mapping>  
  24   <layout type="log4net.Layout.SimpleLayout" />  
  25 </appender>  
\end{verbatim}
Each $<$mapping /$>$ element must contain a severity level, and can also contain a $<$foreColor /$>$ and/or $<$backColor /$>$ element.  Color selection is limited to the following choices:
\begin{itemize}
\item Blue
\item Green
\item Red
\item Yellow
\item Purple
\item Cyan
\item White
\end{itemize}
In addition, you can include ``HighIntensity'' in the color value to use a brighter shade of a color, as shown in the ERROR color mapping in the above configuration example.\\
These appenders are useful only for console-based programs.  It won't hurt anything if you try to use this appender from a UI or web application, you just won't see any of your log messages.  
\subsection{DebugAppender and TraceAppender}
These appenders act as adapters on the .NET System.Diagnostics.Debug and System.Diagnostics.Trace classes.  Because of this, there is very little option in their configurations; both appenders have a single configurable property named ImmediateFlush that controls whether log output is flushed to the Debug or Trace writers immediately:
\begin{verbatim}
   1 <appender name="DebugAppender" type="log4net.Appender.DebugAppender">  
   2     <immediateFlush value="true" />  
   3     <layout type="log4net.Layout.SimpleLayout" />  
   4 </appender>  
\end{verbatim}
I use the DebugAppender routinely to help work problems in the debugger -- the log output shows up right in the debug output window of Visual Studio.  This can be invaluable when trying to isolate race conditions or realtime effects where a breakpoint would ruin the reproducability of the issue.\\
I've used the TraceAppender when extending applications where custom TraceListener implementations were already in use; this allowed existing modules using log4net to adapt immediately to the proprietary TraceListeners, no code required.
FileAppender and RollingFileAppender\\
These appenders write log messages to files. Their configuration is a bit more involved than the other appenders we've discussed. A typical configuration for the FileAppender might look like this:
\begin{verbatim}
   1 <appender name="FileAppender" type="log4net.Appender.FileAppender">  
   2     <file value="log-file.txt" />  
   3     <appendToFile value="true" />  
   4     <encoding value="utf-8" />  
   5     <layout type="log4net.Layout.SimpleLayout" />  
   6 </appender>  
\end{verbatim}
Here's a quick summary of the more common configuration attributes for the FileAppender:
\begin{itemize}
\item file: the full or relative path to the log file;
\item appendToFile: boolean indicating whether the log file should be appended (true) or overwritten (false).  If false, the file overwrite occurs during log4net initialization.  If unspecified, the log file is appended;
\item immediateFlush: boolean indicating whether to flush the log file \mbox{TextWriter} after each log message is written.  The default is true (flush each message after its written);
\item lockingModel: allows control over the log file locking strategy.  This can be either ``log4net.Appender.FileAppender+MinimalLock'' to allow for loose file locking or ``log4net.Appender.FileAppender+ExclusiveLock'' to lock the file during program execution.  The default is the exlusive lock, and I highly recommend you stick with that lock for performance reasons.
\end{itemize}
Now that I've described the FileAppender, heed this advice:\\
Do not use the FileAppender, ever ever ever.  Use the RollingFileAppender instead.\\
The log file managed by FileAppender will be allowed to grow without bounds.  This will Tonya-Harding your application's stability when given enough time.  The RollingFileAppender provides rudimentary log file management, configurable size- or date-boxing of the log file, and limited rolling backups of the log file.
view plaincopy to clipboardprint?
\begin{verbatim}
   1 <appender name="RollingFileAppender" 
               type="log4net.Appender.RollingFileAppender">  
   2     <file value="log-file.txt" />  
   3     <appendToFile value="true" />  
   4     <rollingStyle value="Size" />  
   5     <maxSizeRollBackups value="10" />  
   6     <maximumFileSize value="1MB" />  
   7     <staticLogFileName value="true" />  
   8     <layout type="log4net.Layout.SimpleLayout" />  
   9 </appender>  
\end{verbatim}
There is a lot of configurability to the RollingFileAppender; in addition to the options available to the FileAppender, the RollingFileAppender includes these parameters:
\begin{itemize}
\item rollingStyle: this controls how log files are ``rolled,'' and can be one of the following values:
\begin{itemize}
\item  Once: the log file is rolled every time log4net is initialized (typically at application startup);
\item Size: the log file is rolled once it breaches a certain size;
\item Date: the log file is rolled based on the current date;
\item Composite: the log file is rolled based on size constraints and the current date;
\end{itemize}
\item maximumFileSize: the size cap on the log file.  This is an expression of size in the form of ``\# (KB$|$MB$|$GB)''.  For instance, ``100KB'' or ``10MB'';
\item maxSizeRollBackups: the maximum number of rolled log file backups to maintain when rollingStyle is SIZE; when rollingStyle is COMPOSITE, this indicates the maximum number of roll-offs maintained per day; this property has no effect when rollingStyle is ONCE or DATE;
\item datePattern: the date pattern used to roll files based on date.  The value of this parameter needs to adhere to the format used by the SimpleDateFormatter class;
\item staticLogFileName: a bit of a misnomer - when true this setting indicates whether log4net should actively write logs to the configured file (\mbox{log-file.txt} in our example configuration) and maintain rolling backups by copy.  When false, this setting indicates that log4net will actively log to the latest roll-off file (e.g., \mbox{log-file1.txt}, \mbox{log-file2.txt}, \mbox{log-file3.txt}, etc);
\item countDirection: indicates how roll-off file numbering is managed.  When this parameter is $>=0$, the newest log file will have the largest number; e.g., log-file.txt.5 will be newer than log-file.txt.4.  When countDirection $<$ 0, the newest log file will have the lowest number; e.g., log-file.txt.1 will be newer than \mbox{log-file.txt.2.}  If unspecified, countDirection defaults to ($-1$);
Keep in mind that when using a file appender, the user running the logging process must have rights to create and/or modify the log file in order for log messages to be written properly.  In addition, log4net will create the log file if it does not exist, but it will not create directories in the log file path that do not already exist.  If log4net encounters a problem initializing the file appender (e.g., it cannot create the log file for security reasons), the log file will not be written but your application will continue to execute normally.
\end{itemize}
\subsection{Using Multiple Appenders}
With all of these appenders available, it may seem difficult to choose just one to meet your logging needs.  But why choose one when you can have as many as you want?\\
Using multiple appenders is a simple task of specifying each appender you need under the root logger, like so:
\begin{verbatim}
   1 <root>  
   2     <level value="ALL" />  
   3     <appender-ref ref="DebugAppender" />  
   4     <appender-ref ref="ColoredConsoleAppender" />  
   5 </root>  
\end{verbatim}
You can use as many appenders as you want; however, know that for each appender you use you will accrue some runtime overhead.
\section{Layouts and Patterns}
After that rather lengthy post about common appenders, this discussion of patterns and layouts should be short and sweet.\\
A layout is just a template for your log messages.  Layouts are specified per-appender, and you can specify only one layout for an appender:
\begin{verbatim}
   1 <appender name="ColoredConsoleAppender"
               type="log4net.Appender.ColoredConsoleAppender">  
   2     <layout type="log4net.Layout.SimpleLayout" />  
   3 </appender>  
\end{verbatim}
We've been using the SimpleLayout in the previous tutorials.  This is the easiest layout to use and yields rather a Spartan log:
\begin{verbatim}
   1 DEBUG - this is a debug message  
   2 INFO - this is an info message  
   3 WARN - this is a warn message  
   4 ERROR - this is an error message  
   5 FATAL - this is a fatal message  
\end{verbatim}
The PatternLayout allows you to specify a printf-style template for your log entries using a ``conversion pattern,'' and gives you the opportunity to decorate each entry with some valuable instance data.  For instance, this configuration:
\begin{verbatim}
   1 <appender name="ColoredConsoleAppender"
              type="log4net.Appender.ColoredConsoleAppender">
   2     <layout type="log4net.Layout.PatternLayout">
   3         <conversionPattern value="%date 
                   [%thread] %-5level %logger - %message%newline" />
   4     </layout>  
   5 </appender>  
\end{verbatim}
produces a log that appears like so:
\begin{verbatim}
   1 2008-06-20 12:29:03,541 [2684] DEBUG Tutorial4.Program - this is a debug message
   2 2008-06-20 12:29:03,556 [2684] INFO  Tutorial4.Program - this is an info message
   3 2008-06-20 12:29:03,556 [2684] WARN  Tutorial4.Program - this is a warn message
   4 2008-06-20 12:29:03,556 [2684] ERROR Tutorial4.Program - this is an error message
   5 2008-06-20 12:29:03,556 [2684] FATAL Tutorial4.Program - this is a fatal message
\end{verbatim}
The conversion pattern string can include literal text and the following format expressions:\\
\begin{tabular}{l|p{9cm}}
expression&value\\
\hline
\% appdomain&the friendly name of the appdomain from which the log entry was made\\
\% date&the local datetime when the log entry was made\\
\% exception&a formatted form of the exception object in the log entry, if the entry contains an exception; otherwise, this format expression adds nothing to the log entry\\
\% file&the file name from which the log entry was made; note that using \% file has a significant performance impact and I don't recommend using it\\
\% identity&the user name of the active user logging the entry; this one is less reliable than \% username; note that using \% identity has a significant performance impact and I don't recommend using it\\
\% level&the severity level of the log entry (DEBUG,INFO, etc)\\
\% line&the source code line number from which the log entry was made; slow\\
\% location&some rudimentary call stack information, including file name and line number at which the log entry was made; using\\
\% logger&the name of the logger making the entry; more on this in a bit\\
\% method&the name of the method in which the log entry was made; also slow\\
\% message&the log message itself (don't forget this part!)\\
\% newline&the value of Environment.NewLine\\
\% timestamp&the milliseconds between the start of the application and the time the log entry was made\\
\% type&the full typename of the object from which the log entry was made\\
\% username&the Windows identity of user making the log entry; slow\\
\% utcdate&the UTC datetime when the log entry was made\\
\%\% &a percent sign (\%)\\
\hline
\end{tabular}
\\\\
This sample output is from a single log entry using a conversion pattern containing all of the format expressions above:
\begin{verbatim}
   1 %appdomain: Tutorial4_LayoutsAndPatterns.vshost.exe  
   2 %date: 2008-06-20 13:04:38,020  
   3 %exception:  
   4 %file: D:\...\Tutorial4_LayoutsAndPatterns\Program.cs  
   5 %identity:  
   6 %level: INFO  
   7 %line: 14  
   8 %location: Tutorial4_LayoutsAndPatterns.Program.Main(D:\...\Program.cs:14)  
   9 %logger: Tutorial4_LayoutsAndPatterns.Program  
  10 %method: Main  
  11 %message: this is an info message  
  12 %timestamp: 1015  
  13 %type: Tutorial4_LayoutsAndPatterns.Program  
  14 %username: MYDOMAIN\username  
  15 %utcdate: 2008-06-20 17:04:38,020  
  16 %%: %  
\end{verbatim}
If you want a highly structured and queryable log, then XMLLayout is for you:
\begin{verbatim}
   1  <appender name="ColoredConsoleAppender"
                type="log4net.Appender.ColoredConsoleAppender">  
   2        <layout type="log4net.Layout.XMLLayout" />  
   3      </appender>  
\end{verbatim}
The XMLLayout produces a stream of XML elements representing individual log entries:
\begin{verbatim}
   1. <log4net:event logger="Tutorial4_LayoutsAndPatterns.Program" 
                        timestamp="2008-06-20T13:17:44.2863922-04:00"
                        level="DEBUG" thread="2156" 
                        domain="Tutorial4_LayoutsAndPatterns.vshost.exe" 
                        username="POKERTEK\jchristopher">  
   2      <log4net:message>this is a debug message</log4net:message>  
   3      <log4net:global-properties>  
   4          <log4net:data name="log4net:HostName" value="nc-jchri-l-3" />  
   5      </log4net:global-properties>  
   6  </log4net:event>  
   7  <log4net:event logger="Tutorial4_LayoutsAndPatterns.Program" 
             timestamp="2008-06-20T13:17:44.3176424-04:00" level="INFO"
             thread="2156" domain="Tutorial4_LayoutsAndPatterns.vshost.exe"
             username="POKERTEK\jchristopher">  
   8      <log4net:message>this is an info message</log4net:message>  
   9      <log4net:global-properties>  
  10          <log4net:data name="log4net:HostName" value="nc-jchri-l-3" />  
  11      </log4net:global-properties>  
  12  </log4net:event>  
\end{verbatim}
A few caveats you should note regarding the XMLLayout:
\begin{itemize}
\item the log will contain a flat collection XML elements, but no containing root element; this means that you have to do some fernagling to read the XML as a document;
\item each log entry will contain the username and identity values (see the table above), which are expensive to read and may have a noticable impact on application performance.
\end{itemize}
\section{Using Logger Objects}
We've done a lot log4net configuration in the last few tutorials; time to mix in some code and discuss loggers.  This post is meant to show you the most common pattern of logger use.\\
Crack open Visual Studio, create a new console project, and add a reference to the log4net assembly.\\
Add the following application configuration file to the project:
\begin{verbatim}
   1 <configuration>  
   2   <configSections>  
   3     <section name="log4net"  
   4       type="log4net.Config.Log4NetConfigurationSectionHandler,
                                                            log4net"/>
   5   </configSections>  
   6   
   7   <log4net>  
   8   
   9     <appender name="ConsoleAppender"
                               type="log4net.Appender.ConsoleAppender">
  10       <layout type="log4net.Layout.PatternLayout">  
  11         <conversionPattern value=
                                "%logger [%level]- %message%newline" />
  12       </layout>  
  13     </appender>  
  14   
  15     <root>  
  16       <level value="ALL" />  
  17       <appender-ref ref="ConsoleAppender" />  
  18     </root>  
  19   </log4net>  
  20 </configuration>  
\end{verbatim}
Add the following code to your program.cs file:
\begin{verbatim}
   1 namespace Tutorial5_Loggers  
   2 {  
   3     class Program  
   4     {  
   5         private static log4net.ILog Log = 
                                    log4net.LogManager.GetLogger(
             System.Reflection.MethodBase.GetCurrentMethod()
                                               .DeclaringType );  
   6   
   7         static void Main( string[] args )  
   8         {  
   9             log4net.Config.XmlConfigurator.Configure();  
  10             Log.Info( "this is an info message" );  
  11             Console.ReadLine();  
  12         }  
  13     }  
  14 }  
\end{verbatim}
The logger object is created on line 5 via a the call to LogManager.GetLogger.  Compile and run and check out the output; it'll be similar to the following:
\begin{verbatim}
   1. Tutorial5_Loggers.Program [INFO]- this is an info message  
\end{verbatim}
The first item in the log entry printed to the console is the name of the logger object that issued the log entry.  Because GetLogger was passed a reference to my Program type, the logger name is the fully qualified type name of the Program object.
Add another class to the project:
\begin{verbatim}
   1 namespace Tutorial5_Loggers
   2 {  
   3     class MyClass  
   4     {  
   5         private static log4net.ILog Log = 
                            log4net.LogManager.GetLogger(
              System.Reflection.MethodBase.GetCurrentMethod()
                                           .DeclaringType );  
   6   
   7         public static void WriteLog()  
   8         {  
   9             Log.Info( "this is an info message" );  
  10         }  
  11     }  
  12 }  
\end{verbatim}
and add a call to MyClass.WriteLog to your Main method (see line 7 below):
\begin{verbatim}
   1 static void Main( string[] args )  
   2 {  
   3     log4net.Config.XmlConfigurator.Configure();  
   4   
   5     Log.Info( "this is an info message" );  
   6   
   7     MyClass.WriteLog();  
   8     Console.ReadLine();  
   9 }  
\end{verbatim}
Compile and run, and note the logger name in the second log statement matches the type name of MyClass:
\begin{verbatim}
   1 Tutorial5_Loggers.Program [INFO]- this is an info message  
   2 Tutorial5_Loggers.MyClass [INFO]- this is an info message  
\end{verbatim}
\subsection{Hierarchical Logger Configuration}
You can use loggers this way to isolate logging concerns across your objects, and I wholly recommend you do so.  This will enable you to throttle and direct log output from individual loggers using log4net's hierarchical configuration mechanism.
Update your app.config to the following:
\begin{verbatim}
   1 <configuration>  
   2   <configSections>  
   3     <section name="log4net" 
          type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>  
   4   </configSections>  
   5   
   6   <log4net>  
   7     <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">  
   8       <layout type="log4net.Layout.PatternLayout">  
   9         <conversionPattern value="%logger [%level]- %message%newline" />  
  10       </layout>  
  11     </appender>  
  12     <appender name="FileAppender" type="log4net.Appender.FileAppender">  
  13       <file value="log-file.txt" />  
  14       <appendToFile value="false"/>  
  15       <layout type="log4net.Layout.PatternLayout">  
  16         <conversionPattern value="%logger [%level]- %message%newline" />  
  17       </layout>  
  18     </appender>  
  19   
  20     <root>  
  21       <level value="ALL" />  
  22     </root>  
  23     <logger name="Tutorial5_Loggers">  
  24       <level value="ALL" />  
  25       <appender-ref ref="FileAppender" />  
  26     </logger>  
  27     <logger name="Tutorial5_Loggers.Program">  
  28       <level value="ALL" />  
  29       <appender-ref ref="ConsoleAppender" />  
  30     </logger>  
  31     <logger name="Tutorial5_Loggers.MyClass">  
  32       <level value="ALL" />  
  33     </logger>  
  34   </log4net>  
  35 </configuration>  
\end{verbatim}
On line 12 we add a file appender to the mix; lines 23-33 provide configuration for specific logger objects.  Note that the logger names correspond directly to the namespace-qualified type names and namespaces from our project.  Specifically:
\begin{itemize}
\item on line 23 a logger is configured specifically for the ``Tutorial5\_Loggers'' namespace; this logger is configured to write logs to the file appender;
\item on line 27, a logger is configured for the Program class; this logger is configured to write logs to the console;
\item on line 31, a logger is configured for the MyClass class; this logger is not configured with an appender.
\end{itemize}
Compile and run, and you'll notice that:
\begin{itemize}
\item the console output displays only the log statement from the Program class;
\item a ``log-file.txt'' file is written in the application folder, and this file contains the log statements from both the Program and MyClass types.
\end{itemize}
Now change the level value for the Tutorial5\_Loggers.MyClass from ALL to OFF:
\begin{verbatim}
   1 <logger name="Tutorial5_Loggers.MyClass">  
   2   <level value="OFF" />  
   3 </logger>  
\end{verbatim}
Compile and run, and note that the log-file.txt file no longer contains the log statement from the MyClass object.\\
This hierarchical configuration system can be incredibly useful; a common practice is to disable logging of ``verbose'' objects by targeting their specific type with a logging level set to OFF; another is to provide a ``specific-needs'' logger configured with a special appender, such as a gateway to the windows event log or a remote log viewer.\\
However, the system has a few caveats you need to know about:
\begin{itemize}
\item appenders accumulate through the hierarchy: if the Program class and Tutorial5\_Logger namespace are each configured to append to the console, any log from the Program class will show up twice in the console (once for the class logger and once for the namespace logger);
\item logger levels deeper in the hierarchy trump the shallow ones: if the Program class logging level is set to ALL and the Tutorial5\_Logger namespace logging level is set to OFF, logs from the program class are still written to the appenders configured for Tutorial5\_Logger.
\end{itemize}
\subsection{Log Event Context}
There are times when your log messages need some context to be most useful.  For example, if your application supports multiple concurrent clients, it would be helpful to know the client to which each log statement applies.  If a piece of code is used by several components, it would be nice for the log messages to reflect which component is calling the code.  log4net provides a very simple mechanism to accommodate such needs.\\
Open Visual Studio, create a new console project, and add a reference to the log4net assembly.  Add the following code to your program.cs file:
\begin{verbatim}
   1 namespace Tutorial6_Context  
   2 {  
   3     class Program  
   4     {  
   5         private static log4net.ILog Log = log4net.LogManager.GetLogger(
                 System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );  
   6   
   7         static void Main( string[] args )  
   8         {  
   9             log4net.Config.XmlConfigurator.Configure();  
  10             log4net.ThreadContext.Properties[ "myContext" ]
                                          = "Logging from Main";  
  11             Log.Info( "this is an info message" );  
  12             Console.ReadLine();  
  13         }  
  14     }  
  15 }  
\end{verbatim}
Note line 10, where a property named ``myContext'' is added to the ThreadContext static class and assigned a simple string value.  Next add the following application configuration file to the project:
\begin{verbatim}
   1 <configuration>  
   2   <configSections>  
   3     <section name="log4net"  
   4       type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>  
   5  </configSections>  
   6   
   7   <log4net>  
   8    
   9     <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">  
  10       <layout type="log4net.Layout.PatternLayout">  
  11         <conversionPattern value="%logger (%property{myContext}) 
                        [%level]- %message%newline" />  
  12       </layout>  
  13     </appender>  
  14   
  15     <root>  
  16       <level value="ALL" />  
  17       <appender-ref ref="ConsoleAppender" />  
  18     </root>  
  19   </log4net>  
  20 </configuration>  
\end{verbatim}
Line 11 contains the layout pattern for our log; the \% property{myContext} format specifier will be replaced with the value of the "myContext" property at the time the message is logged.\\
Compile and run; the context value is reflected in the log output:
\begin{verbatim}
   1. Tutorial6_Context.Program (Logging from Main) [INFO]- this is an info message  
\end{verbatim}
\subsubsection{Context Scopes}
There are actually three logging contexts available in log4net.  Like the logger architecture, contexts are organized into a hierarchy where properties in the more granular contexts override property values in less granular contexts.\\
\begin{tabular}{lp{9cm}}
Context&Description\\
\hline
log4net.GlobalContext&A global context shared across all application threads and app domains. If two threads set the same property on the GlobalContext, one value will overwrite the other.\\
log4net.ThreadContext&Any properties set in this context are scoped to the calling thread. In other words, in this context two threads can set the same property to different values without stomping on each other.\\
log4net.ThreadLogicalContext&This context behaves similarly to the ThreadContext, except that the scope is defined by logical thread boundaries. I'll be honest and say that I've never used the ThreadLogicalContext in my career, but if you're working with a custom thread pool algorithm or hosting the CLR, you may find some use for this one.\\
\end{tabular}
\subsubsection{Calculated Context Values}
Context property values don't have to be strings.  You can set the value of a context property to any object reference; the value of the object's ToString method will be used to obtain the context property value when a logging event occurs.  This can be useful when you need a context property to represent a calculated state at the time of each logging event.  For instance, perhaps you want to track your application's use of the CPU:
\begin{verbatim}
   1 namespace Tutorial6_Context  
   2 {  
   3     public class CalcualtedContextProperty  
   4     {  
   5         public override string ToString()  
   6         {  
   7             return Process.GetCurrentProcess().TotalProcessorTime
                                                      .ToString();  
   8         }  
   9     }  
  10 }  
\end{verbatim}
Set a context property value to an instance of this new class:
\begin{verbatim}
   1 namespace Tutorial6_Context  
   2 {  
   3     class Program  
   4     {  
   5         private static log4net.ILog Log = log4net.LogManager.GetLogger(
              System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );  
   6   
   7         static void Main( string[] args )  
   8         {  
   9             log4net.Config.XmlConfigurator.Configure();  
  10             log4net.ThreadContext.Properties[ "myContext" ] = 
                        new CalculatedContextProperty();  
  11             Log.Info( "this is an info message" );  
  12             Console.ReadLine();  
  13         }  
  14     }  
  15 }  
\end{verbatim}
The result is each log entry containing the application's total CPU time at the time the log entry was made:
\begin{verbatim}
   1. Tutorial6_Context.Program (00:00:00.2968750) [INFO]- this is an info message  
\end{verbatim}
\subsection{ThreadContext Stacks}
ThreadContext and ThreadLogicalContext can store property values in stacks (available via the Stacks static property of each class).  These stacks are very handy, as they allow you to track program states in the context of a log message:
\begin{verbatim}
   1 namespace Tutorial6_Context  
   2 {  
   3     class Program  
   4     {  
   5         static log4net.ILog Log = null;  
   6   
   7         static void Main( string[] args )  
   8         {  
   9             log4net.Config.XmlConfigurator.Configure();  
  10             Log = log4net.LogManager.GetLogger(
                    System.Reflection.MethodBase.GetCurrentMethod()
                                     .DeclaringType );  
  11             using( log4net.ThreadContext.Stacks[ "myContext" ]
                                     .Push( "outer" ) )  
  12             {  
  13                 Log.Info( "this is the first message" );  
  14                 using( log4net.ThreadContext.Stacks[ "myContext" ]
                                     .Push( "inner" ) )  
  15                 {  
  16                     Log.Info( "this is the second message" );  
  17                 }  
  18             }  
  19             Log.Info( "this is the third message" );  
  20             Console.ReadLine();  
  21         }  
  22     }  
  23 }  
\end{verbatim}
Pushing a property value onto a stack returns an IDisposable that, when disposed, pops the property value off of the stack.  The logging output reflects the state of the context stack at each logging event; the stack is represented as a space-delimited list, with newer items appearing later in the list:
\begin{verbatim}
   Tutorial6_Context.Program (outer) [INFO]- this is the first message  
   Tutorial6_Context.Program (outer inner) [INFO]- this is the second message  
   Tutorial6_Context.Program ((null)) [INFO]- this is the third message  
\end{verbatim}
Context stacks are incredibly useful for wrapping access to a shared piece of code.  For example, in the following code two methods call the same utility routine; a marker is pushed onto the property stack before each call:
\begin{verbatim}
   1 namespace Tutorial6_Context  
   2 {  
   3     class Program  
   4     {  
   5         static log4net.ILog Log = null;  
   6   
   7         static void Main( string[] args )  
   8         {  
   9             log4net.Config.XmlConfigurator.Configure();  
  10             Log = log4net.LogManager.GetLogger(
                           System.Reflection
                                  .MethodBase
                                  .GetCurrentMethod()
                                  .DeclaringType );  
  11   
  12             FirstAction();  
  13             SecondAction();  
  14   
  15             Console.ReadLine();  
  16   
  17         }  
  18   
  19         static void FirstAction()  
  20         {  
  21             using( log4net.ThreadContext.Stacks[ "myContext" ]
                               .Push( "FirstAction" ) )  
  22             {  
  23                 UtilityRoutine();  
  24             }  
  25         }  
  26   
  27         static void SecondAction()  
  28         {  
  29             using( log4net.ThreadContext.Stacks[ "myContext" ]
                               .Push( "SecondAction" ) )  
  30             {  
  31                 UtilityRoutine();  
  32             }  
  33         }  
  34           
  35         static void UtilityRoutine()  
  36         {  
  37             Log.Info( "this is an info message" );  
  38         }  
  39     }  
  40 }  
\end{verbatim}
Each log message produced by the utility routine reflects the context in which it was called:
\begin{verbatim}
   Tutorial6_Context.Program (from:FirstAction) [INFO]- this is an info message  
   Tutorial6_Context.Program (from:SecondAction) [INFO]- this is an info message  
\end{verbatim}
\section{Filters}
In the Context tutorial I said that my next log4net post would focus on real-world examples.  However, I received this request from a college in the U.K.:\\
I would like to have 2 logs, \dots I would like to have levels Debug, Info \& Warn logged to the one log and all Error \& Fatal logged to the second log. \dots Do you know if this is possible with log4net?\\
This is very easy to do using a feature of log4net I haven't discussed yet: filters.  Filters are applied to individual appenders via the log4net configuration, and they help the appender determine whether a log event should be processed by the appender. They may sound like the appender threshold property, and indeed some filters behave similarly; however, filters offer far more control over logging behavior.
\subsection{Filter Example}
Open Visual Studio, create a new console project, and reference log4net. Add the following code to the Program class:
\begin{verbatim}
   1 namespace Tutorial7_Filters  
   2 {  
   3     class Program  
   4     {  
   5         static void Main( string[] args )  
   6         {  
   7             log4net.Config.XmlConfigurator.Configure();  
   8             log4net.ILog Log = log4net.LogManager.GetLogger(  
   9                 System.Reflection.MethodBase.GetCurrentMethod()
  10                                 .DeclaringType);  
  11             Log.Fatal( "this is a fatal msg" );  
  12             Log.Error( "this is an error msg" );  
  13             Log.Warn( "this is a warn msg" );  
  14             Log.Info( "this is an info msg" );  
  15             Log.Debug( "this is a debug msg" );  
  16         }  
  17     }  
  18 }  
\end{verbatim}
Add an app.config to the project and update it like so:
\begin{verbatim}
   1 <?xml version="1.0" encoding="utf-8" ?>  
   2 <configuration>  
   3   <configSections>  
   4     <section name="log4net"
                 type="log4net.Config.Log4NetConfigurationSectionHandler,
                 log4net"/>  
   5   </configSections>  
   6   <log4net>  
   7     <appender name="LogFileAppender" type="log4net.Appender.FileAppender">  
   8       <file value="log.txt" />  
   9       <filter type="log4net.Filter.LevelRangeFilter">  
  10         <levelMin value="DEBUG" />  
  11         <levelMax value="WARN" />  
  12       </filter>  
  13       <layout type="log4net.Layout.SimpleLayout" />  
  14     </appender>  
  15     <appender name="ErrorFileAppender" type="log4net.Appender.FileAppender">  
  16       <file value="errors.txt" />  
  17       <filter type="log4net.Filter.LevelRangeFilter">  
  18         <levelMin value="ERROR" />  
  19         <levelMax value="FATAL" />  
  20       </filter>  
  21       <layout type="log4net.Layout.SimpleLayout" />  
  22     </appender>  
  23     <root>  
  24       <level value="DEBUG" />  
  25       <appender-ref ref="LogFileAppender" />  
  26       <appender-ref ref="ErrorFileAppender" />  
  27     </root>  
  28   </log4net>  
  29 </configuration>  
\end{verbatim}
This configuration defines two file appenders, each with a unique filter applied (lines 12 and 23).  The filter on the first appender will log events with levels DEBUG, INFO, and WARN; the filter on the second appender will log event with levels ERROR and FATAL.\\
Build and run; the command console will flash for a moment with no output.  Check the working directory and open log.txt:
\begin{verbatim}
   1 WARN - this is a warn msg  
   2 INFO - this is an info msg  
   3 DEBUG - this is a debug msg  
\end{verbatim}
Note that only the DEBUG, INFO, and WARN messages appear in this file.  The errors.txt log file contains only ERROR and FATAL log messages:
\begin{verbatim}
   1 FATAL - this is a fatal msg  
   2 ERROR - this is an error msg  
\end{verbatim}
\subsection{Filter Survey}
Here is a list of the filters available in the log4net distribution:\\
\begin{tabular}{lp{8cm}}
Type Name&Description\\
\hline
log4net.Filter.LevelMatchFilter&Filters log events that match a specific logging level;\\
alternatively&this can be configured to filter events that DO NOT match a specific logging level.\\
log4net.Filter.LevelRangeFilter&Similar to the LevelMatchFilter, except that instead of filtering a single log level, this filters on an inclusive range of contiguous levels.\\
log4net.Filter.LoggerMatchFilter&Filters log events based on the name of the logger object from which they are emitted.\\
log4net.Filter.StringMatchFilter&Filters log events based on a string or regular expression match against the log message.\\
log4net.Filter.PropertyFilter&Filters log events based on a value or regular expression match against a specific context property.\\
log4net.Filter.DenyAllFilter&Effectively drops all logging events for the appender.\\
\end{tabular}
You can also define your own filter by implementing the log4net.Filter.IFilter interface or deriving from the log4net.Filter.FilterSkeleton class.\\
You can apply multiple filters to an appender; they will be evaluated as a chain in configuration order.  Each filter in the chain can either accept the message, deny the message, or punt to the next filter in the chain.   The first filter to explicitly allow or deny a log message stops the filter chain and determines the fate of log message.
\subsection{Logger and Level Filters}
The LoggerMatchFilter filters against the name of the logger emitting the message.  This filter can be configured using the following properties:
\begin{itemize}
\item loggerToMatch: a string value to match against the message's logger name.  The match is made using the String.StartsWith method;
\item acceptOnMatch: a boolean value indicating whether a matching logger name results in accepting the message (true) or rejecting it (false).  This defaults to true, meaning that only matching logger names will be allowed into the appender.
\end{itemize}
The LevelMatchFilter filters against a specific log message level.  This filter can be configured using the following properties:
\begin{itemize}
\item levelToMatch: the log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
\item acceptOnMatch: a boolean value indicating whether to accept log levels matching the levelToMatch property (true), or reject log levels matching the levelToMatch property (false).  Defaults to true.
\end{itemize}
The LevelRangeFilter allows you to configure a range of log levels to filter on:
\begin{itemize}
\item levelMin: the minimum log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
\item levelMax: the minimum log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
\item  acceptOnMatch: a boolean value indicating whether to accept log levels matching the levelToMatch property (true), or to punt filtering to the next filter in the chain (false).  Defaults to true.  Note that any log level outside of the [levelMin, levelMax] range is denied by this filter.
\end{itemize}
\subsection{Message and Property Filters}
If you need to filter messages based on their message content, you need StringMatchFilter.  This filter can be configured as follows:
\begin{itemize}
\item  regexToMatch: a regular expression to match against the log message.  Note this regex is created with the Compiled option enabled for performance;
\item stringToMatch: a static string to match against the log message.  The match is made using the String.IndexOf method to see if the static string exists in the log message, which is a case-sensitive search.
\item acceptOnMatch: a boolean value indicating whether to accept log messages matching the string or regex (true), or to deny log messages matching the string or regex (false).  Defaults to true.
\end{itemize}
Note that any log messages not matching the filter criteria are punted to the next filter in the chain.  If you specify both the regexToMatch and stringToMatch filters, the regexToMatch wins out and the string comparison is never executed, even if the regex fails to match.\\
The PropertyFilter performs the same behavior as the StringMatchFilter, except that the match is made against the value of a context property.  It is configured like so:
\begin{itemize}
\item key: the name of the property value to match;
\item regexToMatch: a regular expression to match against the specified property value.  Note this regex is created with the Compiled option enabled for performance;
\item stringToMatch: a static string to match against the specified property value.  The match is made using the String.IndexOf method to see if the static string exists in the property value, which is a case-sensitive search.
\item acceptOnMatch: a boolean value indicating whether to accept messages with a property value matching the string or regex (true), or to deny messages with a property value matching the string or regex (false).  Defaults to true.
\end{itemize}
Just like the StringMatchFilter, the PropertyFilter will punt filtering when the property value does not match the filter criteria, and regexToMatch trumps and excludes stringToMatch.  In addition, if the property identified does not exist in the current context, filtering is punted.
\subsection{DenyAllFilter}
This filter simply denies all filtering. When this is used, it's always at the end of a filter chain to block unwanted log messages from the appender.
\subsection{An Extended Example}
Update Program.cs to the following:
\begin{verbatim}
   1 namespace Tutorial7_Filters  
   2 {  
   3     class Program  
   4     {  
   5         static void Main( string[] args )  
   6         {  
   7             log4net.Config.XmlConfigurator.Configure();  
   8             log4net.ILog Log = log4net.LogManager.GetLogger(
                              System.Reflection.MethodBase
                                    .GetCurrentMethod()
                                    .DeclaringType );  
   9             log4net.ILog OMGLog = log4net
                                    .LogManager
                                    .GetLogger( "OMGLogger" );  
  10               
  11             Log.Fatal( "this is a fatal msg" );  
  12             Log.Error( "this is an error msg" );  
  13             Log.Warn( "this is a warn msg" );  
  14             Log.Info( "this is an info msg" );  
  15             Log.Debug( "this is a debug msg" );  
  16             OMGLog.Fatal( "OMG!!  this is a fatal msg" );  
  17             OMGLog.Error( "OMG!!  this is an error msg" );  
  18             OMGLog.Warn( "OMG!!  this is a warn msg" );  
  19             OMGLog.Info( "OMG!!  this is an info msg" );  
  20             OMGLog.Debug( "OMG!!  this is a debug msg" );  
  21         }  
  22     }  
  23 }  
\end{verbatim}
On lines 8 and 9 two logger objects are created, one based off of the name of the containing type and another named simply ``OMGLogger''.  Now update the app.config to the following:
\begin{verbatim}
   1 <?xml version="1.0" encoding="utf-8" ?>  
   2 <configuration>  
   3   <configSections>  
   4     <section name="log4net"
          type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>  
   5   </configSections>  
   6   <log4net>  
   7     <appender name="OMGLogAppender" type="log4net.Appender.FileAppender">  
   8       <file value="omglog.txt" />  
   9         
  10       <filter type="log4net.Filter.LevelRangeFilter">  
  11         <levelMin value="ERROR" />  
  12         <levelMax value="FATAL" />  
  13         <acceptOnMatch value="false" />  
  14       </filter>  
  15       <filter type="log4net.Filter.LoggerMatchFilter">  
  16         <loggerToMatch value="OMGLogger" />  
  17       </filter>  
  18       <filter type="log4net.Filter.DenyAllFilter" />  
  19       <layout type="log4net.Layout.SimpleLayout" />  
  20     </appender>  
  21     <root>  
  22       <level value="DEBUG" />  
  23       <appender-ref ref="OMGLogAppender" />  
  24     </root>  
  25   </log4net>  
  26 </configuration>  
\end{verbatim}
Compile and run, the command console will blip on your screen.  Open the omglog.txt file:
\begin{verbatim}
   FATAL - OMG!!  this is a fatal msg  
   ERROR - OMG!!  this is an error msg  
\end{verbatim}
Note that because of our chained filter, only log messages that meet the following criteria were allowed into the omglog.txt file:
\begin{verbatim}
   the log message level is ERROR or FATAL;
   the log message originated from the OMGLogger.
\end{verbatim}
\section{Lossy Logging}
Ok, so I know I've said twice now that I was going to relay some real-life log4net experiences, but a few days ago Georg Jansen (author of the very kewl Log4Net Dashboard, which I plan to describe in a future post) demonstrated a feature of log4net I've never used before: lossy logging.  After using the feature for a few days, I'm completely sold on it and decided to write up another tutorial.
\subsection{What is Lossy Logging?}
Logging is a very useful tool, but it's not something you want to leave enabled in production if you don't need it.  Each log message take a few cycles away from your application, and the persistence of messages does consume system resources.  Of course you can configure log4net to disable logging, either by setting the root logger level to OFF or removing all appenders from the root logger. The problem is that by disabling logging altogether, you won't get any juicy details if something goes awry in your application.\\
Lossy logging gives you a great compromise: under normal operation your application will not log any messages; however, if your application logs an error, a small batch of messages leading up to the error is placed into the log, giving you the error and a snapshot of system activity just before it happened.  How awesome it that?!
\subsection{Lossy Logging Example}
Open Visual Studio, create a new console project, and reference log4net.  Add the following code to the Program class:
\begin{verbatim}
   1. namespace Tutorial8_LossyLog  
   2. {  
   3.     class Program  
   4.     {  
   5.         static void Main( string[] args )  
   6.         {  
   7.             log4net.Config.XmlConfigurator.Configure();  
   8.             static log4net.ILog Log = log4net.LogManager.GetLogger(  
   9.                 System.Reflection.MethodBase
    .                                  .GetCurrentMethod()
    .                                  .DeclaringType  
  10.             );  
  11.                  
  12.             for( int i = 0; i < 100; ++i )  
  13.             {  
  14.                 Log.DebugFormat( "this is debug msg #{0}", i );  
  15.             }  
  16.                  
  17.             Log.Error( "error: an error occurred!" );             
  18.             Log.Warn( "warning: you've been warned" );  
  19.         }  
  20.     }  
  21. }  
\end{verbatim}
The program outputs a series of 100 numbered debug log messages, followed by a single error message and a warning message.\\
Add an app.config to the project:
\begingroup
\fontsize{9pt}{11pt}
\begin{verbatim}
   1 <?xml version="1.0" encoding="utf-8" ?>  
   2 <configuration>  
   3   <configSections>  
   4     <section name="log4net" 
          type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>  
   5   </configSections>  
   6   
   7   <log4net>  
   8     <appender name="ConsoleAppender" type="log4net.Appender
                                              .ConsoleAppender">  
   9       <layout type="log4net.Layout.SimpleLayout" />  
  10     </appender>  
  11   
  12     <appender name="LossyConsoleAppender" 
                  type="log4net.Appender.BufferingForwardingAppender">  
  13       <bufferSize value="20" />  
  14       <lossy value="true"/>  
  15       <evaluator type="log4net.Core.LevelEvaluator">  
  16         <threshold value="ERROR" />  
  17       </evaluator>  
  18       <appender-ref ref="ConsoleAppender" />  
  19     </appender>  
  20   
  21     <root>  
  22       <level value="DEBUG" />  
  23       <appender-ref ref="LossyConsoleAppender" />  
  24     </root>  
  25   </log4net>  
  26 </configuration>  
\end{verbatim}
\endgroup
The logging configuration defines two appenders, one very generic Console appender and a BufferingForwardingAppender.  As the name implies, the latter appender buffers log messages and forwards them in batches to one or more other appenders.  You can probably tell from the configuration XML that I've set this appender up with a 20-message buffer.  The lossy and evaluator parameters work together to define when the log message buffer is forwarded to the "base" appender.  More on that in a moment \dots \\
Build and run; the command console will output the following:
\begin{verbatim}
   1. DEBUG - this is debug msg #81  
   2. DEBUG - this is debug msg #82  
   3. DEBUG - this is debug msg #83  
   4. DEBUG - this is debug msg #84  
   5. DEBUG - this is debug msg #85  
   6. DEBUG - this is debug msg #86  
   7. DEBUG - this is debug msg #87  
   8. DEBUG - this is debug msg #88  
   9. DEBUG - this is debug msg #89  
  10. DEBUG - this is debug msg #90  
  11. DEBUG - this is debug msg #91  
  12. DEBUG - this is debug msg #92  
  13. DEBUG - this is debug msg #93  
  14. DEBUG - this is debug msg #94  
  15. DEBUG - this is debug msg #95  
  16. DEBUG - this is debug msg #96  
  17. DEBUG - this is debug msg #97  
  18. DEBUG - this is debug msg #98  
  19. DEBUG - this is debug msg #99  
  20. ERROR - error: an error occurred!  
\end{verbatim}
The program issues a total of 102 log messages (100 DEBUG, one ERROR, and one WARN), but the console only contains 20 messages (19 DEBUG and 1 ERROR).  So what happened to the other 82 DEBUG and WARN messages?\\
When the BufferingForwardingAppender's lossy property is enabled, the appender will buffer log messages without forwarding them.  If the buffer fills up, the oldest messages are dropped from the buffer to make room for the new messages.\\
The evaluator property determines when the appender forwards the messages from the buffer to its base appenders.  There is only one evaluator defined in log4net - the LevelEvaluator.  The LevelEvaluator triggers the forward when a log message is received that meets or exceeds the configured threshold.  The example above is configured so that an ERROR message triggers the appender to forward its buffer to the ConsoleAppender.
\subsection{Lossy Appender Types}
Here is a list of appenders in the log4net distribution that can operate ``lossy:''
\begin{verbatim}
	log4net.Appender.AdoNetAppender
	log4net.Appender.RemotingAppender
	log4net.Appender.SmtpAppender
	log4net.Appender.SmtpPickupDirAppender
	log4net.Appender.BufferingForwardingAppender
\end{verbatim}
\section{Log4Net Recommended Practices}
\subsection{Your code}
So far my log4net writings have focused on specific aspects of the log4net framework.  These next posts are about putting the pieces together.\\
To that end, I would like to start with one recent example of how logging has saved hide.
\subsubsection{The Call}
My company phone starting cock-a-doodle-dooing about 3pm one afternoon.  It was the Director of Support calling - I'll refer to him as Bob - he was on-site trying to get a kiosk up and running for a major client, but a security configuration application was reporting a failure.  This application is basically a permissions engine that modifies DACLs on cryptographic keys, files, and registry keys based on a database of access rules.  The client was going live in an hour or so, so time was a critical factor.\\
``I've tried everything I know - the database is correct, the AD users are there, the security service is running, and I'm running as an administrator,'' he said nervously, ``but it keeps failing at the same point on this one machine.  It worked on all the other machines, but this one kiosk keeps failing.''\\
``Ok, let's open the log file.  It should be at $<$file path$>$.  Find it?'' I asked.
``Um\dots . yep.  Ok, it's open.''\\
``Alright.  Jump to the end, find the last line.  Read it to me.''\\
This is the layout of the log file for the application:
\begin{verbatim}
   1 DATETIME LOGGERNAME [LEVEL] (CONTEXT) MESSAGE_STACKTRACE  
\end{verbatim}
The last two lines in the log appeared like so:\\
\begin{verbatim}
   1 12:34:56 TaskExecutionContext [DEBUG] (ACLRuleBuilding) 
          Attempting to locate computer domain name using WMI class 
          [Win32_ComputerSystem] property [Domain].  
   2   
   3 12:34:56 SetCryptoKeyDACLTask [ERROR] (ACLRuleBuilding)
                        An exception was raised while translating
                        the user name to the domain: 
                     System.Runtime.InteropServices.COMException at ...  
\end{verbatim}
I had never encountered this error before in development, testing, or the two years the application's been used in the field.  However, the data in that one log message was enough for me to help Bob resolve the issue over the phone.  There were four bits of information that I gleaned from Bob's reading of that log message that allowed me to isolate the problem:
\begin{enumerate}
\item The logger name told me that the SetCryptoKeyDACLTask class issued the error.
\item The logging context told me that the error was occurring while the application was building ACL rules (as opposed to applying them).
\item The log message told me the failure was occurring when the application was attempting to translate a username to the computer's domain.
\item The preceding DEBUG log message indicates that the application was trying to find the computer's domain name immediately before the exception was raised.
\end{enumerate}
``Hmmm, haven't seen that one before either,'' I said, ``but it looks like the app is failing when it's trying to determine the computer's domain.  Any idea why this might be happening on this machine as opposed to the others?''\\
``Well, I had to add the machine to the domain and then \dots.''  I hear a loud *smack* as Bob hits himself in the head.  ``Okay, I think I figured it out.''\\
It turns out that Bob had neglected to reboot the kiosk after adding it to the domain, so when my application started spelunking through WMI to determine the computer's domain, an exception was being raised.  After a few minutes, the kiosk was running perfectly, and Bob and the client enjoyed a smooth go-live.\\
All things considered, Bob would have resolved this issue on his own eventually by blindly rebooting the machine and starting the security configuration process over again.  The point is that the application log contained enough information to isolate the problem to a very specific cause without resorting to looking at the source code.  COMExceptions are notoriously ambiguous; if that was all we had to go on, we may not have been able to determine the cause of the exception.
\subsubsection{Some Recommended Practices}
Let's take a look at some of the code that produced the log message:
\begin{verbatim}
   1 namespace Log4Net_BestPractices1  
   2 {  
   3     public class SetCryptoDACLTask : ITask  
   4     {  
   5         static log4net.ILog Log = log4net.LogManager.GetLogger(  
   6             System.Reflection.MethodBase.GetCurrentMethod().DeclaringType  
   7         );  
   8           
   9         string userName;  
  10           
  11         public void Execute( ITaskExecutionContext context )  
  12         {          
  13             if( Log.IsDebugEnabled )  
  14             {  
  15                 Log.DebugFormat( "Executing task under context
                 [{0}]...", ( null == context ? "null" : context.Description ) );  
  16             }  
  17               
  18             // ...  
  19               
  20             using( log4net.NDC.Push( "ACLRuleBuilding" ) )  
  21             {  
  22                 // ...  
  23                 string principalName = null;  
  24                   
  25                 try  
  26                 {  
  27                     principalName =  
  28                         context.TranslatePrincipalNameToDomain(  
  29                             userName  
  30                         );  
  31                 }  
  32                 catch( Exception e )                  
  33                 {  
  34                     Log.Error(  
  35                         "An exception was raised while translating
                                the user name to the domain",  
  36                         e  
  37                     );  
  38                       
  39                     throw;  
  40                 }  
  41                   
  42                 // ...  
  43             }  
  44               
  45             // ...  
  46               
  47             Log.Debug( "Task execution has completed." );  
  48         }  
  49     }  
  50 }  
\end{verbatim}
This code demonstrates some effective logging techniques I recommend you employ in your own applications:
\begin{enumerate}
\item Use a unique logger object for each type in your application (see line 5).  This will automagically tag each log message with the class that wrote it.  Using this technique provides a log that reads like a novel of your application's activity. 
\item Whenever you catch an exception, log it (see line 30).  Even if you just plan to throw it again, log it.  In addition, log4net knows how to format Exception objects, so don't try and build your own string from the exception data.
\item Don't be afraid to pepper your application with piddly little log messages (see lines 15 and 47).  Each one becomes a marker of activity and can prove invaluable when trying to work an issue.  While logging does consume resources, that consumption can be controlled and optimized (something I'll talk about in the next post).  In all but the most CPU-intensive applications, the impact of logging won't be noticed when configured properly.
\item Whenever you use one of the *Format overrides (see line 15), be extra-special-careful about validating the argument list.  It's very easy to forget to check for null references before using a property accessor, for example, because ``it's just logging code.''
\item Always remember that the argument list is evaluated before the logging method is called.  If an argument to the log method is expensive to obtain, be sure to guard your log statement with a check of the appropriate Is*Enabled property (see line 13).
\item Before an object calls on a shared dependency, consider pushing a tag onto the log context stack (see line 20).  This will provide continuity in the log, allowing you to determine the caller of the shared code that logged a particular message.
\item Whenever you use a formatted log statement, surround the format argument placeholders (the \{\}'s) with brackets or parentheses (see line 15).  Doing this will mark the areas in each log message that vary, making the log scan a bit easier.  In addition, it makes empty or null formatting arguments more obvious.  For instance, if the log message in line 15 was formatted with an empty context.Description value, the message would appear as ``Executing task under context []\dots ''  Without those brackets, the same message would be written as ``Executing task under context \dots'' The former message makes it obvious that the context failed to provide a description value, the latter does not.
\end{enumerate}
\subsection{Isolating Bugs}
I realize it's been a while since I've written about logging, but my experiences this morning compelled me to share.  The muse for this post was a very simple bug located in a rat's nest of complexity.\\
The code in question drives the I/O layer in a device that is filled with proprietary hardware.   There are about three dozen channels of internal communication when this thing is running, which doesn't include any of its networking.  So lots of asynchronous I/O and threading.  All supporting an awesome graphics and physical interface layer that is equally complex on its own.\\
Except that today, it was a paperweight.  In fact, you couldn't even use the operating system effectively.  Eventually task manager would pop up and show that something in the application was suffocating the CPU.  I was not looking forward to diagnosing this problem given the level of complexity involved.  I expected to spend the morning on it, but in all it took about 10 minutes to find and fix the problem.\\
I had worked with the application to know what pattern of messages to expect in the log files, but when I opened them I found some of the messages to be missing.  Specifically, the messages pertaining to just one of those three dozen communication channels I mentioned earlier.  After some initial testing, I had isolated the problem to a case where that channel was misconfigured.  I re-ran the application and grabbed the fresh logs.\\
Since I mirror my class structure in logger objects, isolating the relevant log entries was easy using logparser.  The list was surprisingly short, ending with this message:
\begin{verbatim}
   1. initiating PSU polling thread   
\end{verbatim}
I quickly found this message in my code:
\begin{verbatim}
   1. void PollForReports()  
   2. {  
   3.     Log.Info( ``initiating PSU polling thread'' );  
   4.     while( 1 == Interlocked.Read( ref suspendInterlock ) )  
   5.     {  
   6.         continue;  
   7.     }  
   8.    
   9.     RequestSerialNumber();  
  10.     Log.Debug( "requested PSU serial number ..." );  
  11.           
  12.     // ...  
\end{verbatim}
As you can see, a ``requested PSU serial number\dots '' log message should have been written almost immediately after the last message I found in the log.  Something in the code after the ``initiating PSU polling thread'' message is written and before the ``requested PSU serial number \dots '' message is locking the CPU. \\
Do you see it - the improperly implemented spin lock?  It's pretty obvious when you know where to look, and logging can make it a lot easier to know where to look.
\subsection{Extension Methods for Deferred Log4Net Message Formatting}
In a recent post I described some initial impressions of the MS Live Labs Simple Logging Framework (SLF).  One of the things I really like about SLF is the use of lambas as a way to defer execution of potentially slow or unchecked message formatting code.  I also railed on the idea of creating a completely new effort when log4net is an active open-source project.\\
So, here I am putting my money where my mouth is: I've created some extension methods for instances of ILog that accept lambdas - now if you use log4net in a C\# 3.0+ environment, you can defer message formatting as easily as you can in SLF.  The code is quite simple:
\begin{verbatim}
   1 using log4net;  
   2 namespace Log4NetExtensions  
   3 {  
   4     public static class Log4NetExtensionMethods  
   5     {  
   6         public static void Debug( this ILog log, Func<string> formattingCallback )  
   7         {  
   8             if( log.IsDebugEnabled )  
   9             {  
  10                 log.Debug( formattingCallback() );  
  11             }  
  12         }  
  13         public static void Info( this ILog log, Func<string> formattingCallback )
  14         {  
  15             if( log.IsInfoEnabled )  
  16             {  
  17                 log.Info( formattingCallback() );  
  18             }  
  19         }  
  20         public static void Warn( this ILog log, Func<string> formattingCallback )
  21         {  
  22             if( log.IsWarnEnabled )  
  23             {  
  24                 log.Warn( formattingCallback() );  
  25             }  
  26         }  
  27         public static void Error( this ILog log, Func<string> formattingCallback )
  28         {  
  29             if( log.IsErrorEnabled )  
  30             {  
  31                 log.Error( formattingCallback() );  
  32             }  
  33         }  
  34         public static void Fatal( this ILog log, Func<string> formattingCallback )
  35         {  
  36             if( log.IsFatalEnabled )  
  37             {  
  38                 log.Fatal( formattingCallback() );  
  39             }  
  40         }  
  41      }  
  42 }   
\end{verbatim}
Each method of the ILog interface gets its own override in the form of an extension method.  The method accepts a Func$<$string$>$ that allows you to capture log message formatting in a lamba expression, and hence defer its execution until absolutely necessary (or avoid it altogether).  Here are some quick and dirty unit tests to demonstrate the basic use and functionality:
\begin{verbatim}
   1 using NUnit.Framework;  
   2 namespace Log4NetExtensions.Tests  
   3 {  
   4     [TestFixture]  
   5     public class Log4NetExtensionTests  
   6     {  
   7         log4net.ILog Log;  
   8         log4net.Appender.MemoryAppender appender;  
   9         [TestFixtureSetUp]  
  10         public void FixtureSetUp()  
  11         {  
  12             Log = log4net.LogManager.GetLogger( 
                 System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );  
  13             appender = new log4net.Appender.MemoryAppender   
  14             {  
  15                 Name = "Memory Appender",  
  16                 Threshold = log4net.Core.Level.Debug  
  17             };  
  18             log4net.Config.BasicConfigurator.Configure( appender );
  19         }  
  20         [SetUp]  
  21         public void TestSetUp()  
  22         {  
  23             appender.Clear();              
  24             log4net.Core.LoggingEvent[] events = appender.GetEvents();  
  25             Assert.That( 0 == events.Length, "failed to clear appender of log
                                               events" );  
  26             Log.Logger.Repository.Threshold = log4net.Core.Level.Debug;  
  27         }  
  28         [Test]  
  29         public void LogViaLambdaTest()  
  30         {  
  31             Log.Debug( () => "Hello World!" );  
  32             log4net.Core.LoggingEvent[] events = appender.GetEvents();
  33               
  34             Assert.That( 1 == events.Length, "failed to log via lamba" );  
  35             Assert.That(   
  36                 StringComparer.CurrentCulture.Equals(   
  37                     "Hello World!",   
  38                     events[ 0 ].RenderedMessage                     
  39                 ),  
  40                 "rendered message does not match (via lambda)"  
  41             );  
  42         }  
  43         [Test]  
  44         public void LogWithLocalVariableReference()  
  45         {  
  46             string value = "World!";  
  47             Log.Debug( () => "Hello " + value );  
  48             log4net.Core.LoggingEvent[] events = appender.GetEvents();  
  49             Assert.That( 1 == events.Length, "failed to log with
                                   local variable reference" );  
  50             Assert.That(  
  51                 StringComparer.CurrentCulture.Equals(  
  52                     "Hello World!",  
  53                     events[ 0 ].RenderedMessage  
  54                 ),  
  55                 "rendered message does not match (local variable reference)"  
  56             );  
  57         }  
  58         [Test]  
  59         public void LambdaIsNotEvaluatedAtInactiveLogLevel()  
  60         {              
  61             Log.Logger.Repository.Threshold = log4net.Core.Level.Error;
  62             bool evaluated = false;  
  63             Log.Debug( () =>   
  64                 {   
  65                     evaluated = true;  
  66                     return "Hello World!";  
  67                 }  
  68             );  
  69             Assert.That( ! evaluated, "lamba was evaluated at 
                              inactive log level" );  
  70             Log.Error( () =>  
  71                 {  
  72                     evaluated = true;  
  73                     return "Hello World!";  
  74                 }  
  75             );  
  76             Assert.That( evaluated, "lamba was not evaluated at
                             active log level" );  
  77         }  
  78     }  
  79 }  
\end{verbatim}
Play with it, see if you like it.  I will to.  Any suggestions or comments are encouraged.  If there is enough interest I'll see about submitting the extensions to the apache project. 
\end{document}
